Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fix(logger): change logging to use stdout #748

Merged
merged 5 commits into from
Apr 14, 2022
Merged

fix(logger): change logging to use stdout #748

merged 5 commits into from
Apr 14, 2022
+147 −143

Conversation

dreamorosi
Copy link
Contributor

@dreamorosi dreamorosi commented Apr 8, 2022 •
edited
Loading

Description of your changes

As reported by user @olanb7 on the community Slack and in #747 before this PR Logger would output logs like this:

2022-04-08T10:58:44.811Z	b6511ee9-4873-404e-b60c-a23cb45d3ff2	INFO {"cold_start":false,"function_arn":"arn:aws:lambda:eu-west-2:12345:function:test","function_memory_size":1024,"function_name":"test","function_request_id":"b6511ee9-4873-404e-b60c-a23cb45d3ff2","level":"INFO","message":"test message","service":"test","timestamp":"2022-04-08T10:58:44.811Z"}

These logs, although containing a structured JSON, are not JSON as they are always prefixed by 2022-04-08T10:58:44.811Z b6511ee9-4873-404e-b60c-a23cb45d3ff2 INFO.

This also confirmed by a line in the Lambda docs (emphasis mine):

The Node.js runtime logs the START, END, and REPORT lines for each invocation. It adds a timestamp, request ID, and log level to each entry logged by the function.

This behaviour works well with CloudWatch but the presence of these prefixes was an issue for customers wanting to use these structured logs elsewhere (both 3rd party services and AWS Managed Grafana).

From this PR onwards Logger will be using its own internal and private version of the Console class that only outputs the structured JSON log without any prefix:

{"cold_start":false,"function_arn":"arn:aws:lambda:eu-west-2:12345:function:test","function_memory_size":1024,"function_name":"test","function_request_id":"b6511ee9-4873-404e-b60c-a23cb45d3ff2","level":"INFO","message":"test message","service":"test","timestamp":"2022-04-08T10:58:44.811Z"}

Aside from 3-lines change in the Logger class, all the rest of the changes in this PR are related to the unit and integration tests.

How to verify this change

See the results of checks inside this PR and e2e tests (to be run).

Also see screenshot below:
image

Related issues, RFCs

#747

PR status

Is this ready for review?: YES
Is it a breaking change?: NO

Checklist

  • My changes meet the tenets criteria
  • I have performed a self-review of my own code
  • I have commented my code where necessary, particularly in areas that should be flagged with a TODO, or hard-to-understand areas
  • My changes generate no new warnings
  • The code coverage hasn't decreased
  • I have added tests that prove my change is effective and works
  • New and existing unit tests pass locally and in Github Actions
  • Any dependent changes have been merged and published in downstream module
  • The PR title follows the conventional commit semantics

Breaking change checklist

N/A

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

@dreamorosi dreamorosi self-assigned this Apr 8, 2022
@dreamorosi dreamorosi added this to the production-ready-release milestone Apr 8, 2022
@dreamorosi dreamorosi linked an issue Apr 8, 2022 that may be closed by this pull request
Feature request: logger should write to stdout directly #747
Closed
@github-actions github-actions bot added the bug Something isn't working label Apr 8, 2022
@dreamorosi dreamorosi mentioned this pull request Apr 8, 2022
Closed
@dreamorosi dreamorosi force-pushed the fix/logger/use_stdout branch from 409dc32 to ea2c672 Compare April 13, 2022 14:54
@dreamorosi dreamorosi added the logger This item relates to the Logger Utility label Apr 13, 2022
@dreamorosi dreamorosi requested review from ijemmy and saragerion April 13, 2022 17:11
@dreamorosi dreamorosi marked this pull request as ready for review April 13, 2022 17:11
@dreamorosi
Copy link
Contributor Author

e2e test results here (passing) https://github.com/awslabs/aws-lambda-powertools-typescript/actions/runs/2162686619

@dreamorosi dreamorosi requested a review from flochaz April 14, 2022 09:53
ijemmy
ijemmy reviewed Apr 14, 2022
View reviewed changes
Copy link
Contributor

@ijemmy ijemmy left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for cleaning up those small things.

I have one question just to double check.

packages/logger/tests/unit/middleware/middy.test.ts

describe('Middy middleware', () => {

const ENVIRONMENT_VARIABLES = process.env;

beforeEach(() => {
jest.resetModules();
// eslint-disable-next-line @typescript-eslint/no-empty-function
jest.spyOn(console, 'log').mockImplementation(() => {});
jest.spyOn(process.stdout, 'write').mockImplementation(() => null as unknown as boolean);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why double cast? Is this intentional?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's only to please the TypeScript compiler.

If doing null as boolean it would give me this error:

error TS2352: Conversion of type 'null' to type 'boolean' may be a mistake because neither type sufficiently overlaps with the other. If this was intentional, convert the expression to 'unknown' first.

jest.spyOn(process.stdout, 'write').mockImplementation(() => null as boolean);

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Got it. Thanks.

flochaz
flochaz approved these changes Apr 14, 2022
View reviewed changes
Copy link
Contributor

@flochaz flochaz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@dreamorosi dreamorosi merged commit 0781a47 into main Apr 14, 2022
@dreamorosi dreamorosi deleted the fix/logger/use_stdout branch April 14, 2022 11:00
@dreamorosi dreamorosi mentioned this pull request Jun 1, 2022
Closed
@dreamorosi dreamorosi mentioned this pull request Jul 29, 2022
Closed
@mrerichoffman
Copy link

mrerichoffman commented Sep 21, 2022 •
edited
Loading

I'm curious does this change break tracing in cloudwatch? I thought that the default console log formatting is used to correlate logs across requests in cloudwatch tracing and x-ray.

@dreamorosi
Copy link
Contributor Author

Hi @mrerichoffman, thanks for the message. I think I have an idea of what you're referring to but I'd like to make sure we are on the same page.

Would you mind please opening and elaborating on what you're (not) seeing and what you're expecting to see and where? This would also help others find the same issue in the future since this is an old PR.

Thank you!

@shdq shdq mentioned this pull request Nov 14, 2022
Merged
13 tasks
@dreamorosi dreamorosi mentioned this pull request Aug 8, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@flochaz flochaz flochaz approved these changes

@ijemmy ijemmy ijemmy approved these changes

@saragerion saragerion Awaiting requested review from saragerion

Assignees

@dreamorosi dreamorosi

Labels
bug Something isn't working logger This item relates to the Logger Utility
Projects
None yet
Milestone
production-ready-release
Development

Successfully merging this pull request may close these issues.

Feature request: logger should write to stdout directly
4 participants
@dreamorosi @mrerichoffman @ijemmy @flochaz